APM开源方案Matrix —— TraceCanary

Posted on | In

本文主要介绍Matrix的Trace部分，主要涉及帧率、ANR、慢函数、启动耗时的检测逻辑。

Trace Canary主要特性

Trace Canary主要特性：

  • 编译期动态修改字节码, 高性能记录执行耗时与调用堆栈
  • 准确的定位到发生卡顿的函数，提供执行堆栈、执行耗时、执行次数等信息，帮助快速解决卡顿问题
  • 自动涵盖卡顿、启动耗时、页面切换、慢函数检测等多个流畅性指标

Tracer模块主要结构：

其中：

  • FrameTracer负责帧率检测
  • AnrTracer负责ANR问题检测
  • EvilMethodTracer负责检测慢函数
  • StartupTracer负责应用启动耗时检测

帧率检测

FrameTracer部分主要做帧率、掉帧、帧耗时等检测，具体实现逻辑在FrameTracer和UIThreadMonitor。

Demo中的入口在TestFpsActivity，onCreate()中通过FrameTracer.onStartTrace()开启检测，页面退出时通过FrameTracer.onCloseTrace()结束检测，并移除监控回调。

从使用侧开始，看看帧率的计算逻辑。

TestFpsActivity：
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
sample.tencent.matrix.trace.TestFpsActivity

protected void onCreate(@Nullable Bundle savedInstanceState) {
	// 启动帧率检测，使用FrameTrace计算FPS
	Matrix.with().getPluginByClass(TracePlugin.class).getFrameTracer().onStartTrace();
	// 添加帧率回调
	Matrix.with().getPluginByClass(TracePlugin.class).getFrameTracer().addListener(mDoFrameListener);
}

protected void onDestroy() {
	super.onDestroy();
	// 移除帧率回调
	Matrix.with().getPluginByClass(TracePlugin.class).getFrameTracer().removeListener(mDoFrameListener);
	// 关闭帧率检测
	Matrix.with().getPluginByClass(TracePlugin.class).getFrameTracer().onCloseTrace();
}

看下TestFpsActivity的FPS监控回调部分：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
sample.tencent.matrix.trace.TestFpsActivity

// 异步线程
private static HandlerThread sHandlerThread = new HandlerThread("test");

// 帧率检测回调
private IDoFrameListener mDoFrameListener = new IDoFrameListener(new Executor() {
        Handler handler = new Handler(sHandlerThread.getLooper());

        @Override
        public void execute(Runnable command) {
            //将回调方法放到异步线程执行
            handler.post(command);
        }
    }) {
        @Override
        public void doFrameAsync(String visibleScene, long taskCost, long frameCostMs, int droppedFrames, boolean isContainsFrame) {
            super.doFrameAsync(visibleScene, taskCost, frameCostMs, droppedFrames, isContainsFrame);
            // 计算总的掉帧数
            count += droppedFrames;
        }
    };

回调接口IDoFrameListener支持将同步和异步回调方法：doFrameSync()和doFrameAsync，需要使用侧传入一个Executor。

解释下IDoFrameListener.doFrameAsync()的参数含义：

  • visibleScene：场景名称，默认是Activity的类名
  • taskCost：主线程每一帧耗时
  • frameCostMs：帧率检测时用不到
  • droppedFrames：掉帧数
  • isContainsFrame：是否包含一帧

这里提一下visibleScene的获取逻辑：Matrix初始化时，AppActiveMatrixDelegate.controller()内部通过Application. registerActivityLifecycleCallbacks()监听Activity生命周期。当Activity start时，将activity.getClass().getName()做为visibleScene。FrameTracer再通过AppMethodBeat.getVisibleScene()获取visibleScene。

继续看下回调方法doFrameAsync()的上游逻辑。

FrameTracer.notifyListener()：

IDoFrameListener.doFrameAsync()是在FrameTracer.notifyListener()中调用的：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
com.tencent.matrix.trace.tracer.FrameTracer

    private void notifyListener(final String visibleScene, final long taskCostMs, final long frameCostMs, final boolean isContainsFrame) {
        long start = System.currentTimeMillis();
        try {
            synchronized (listeners) {
                for (final IDoFrameListener listener : listeners) {
                    if (config.isDevEnv()) {
                        listener.time = SystemClock.uptimeMillis();
                    }
                    // 计算掉帧数
                    final int dropFrame = (int) (taskCostMs / frameIntervalMs);

                    listener.doFrameSync(visibleScene, taskCostMs, frameCostMs, dropFrame, isContainsFrame);
                    if (null != listener.getExecutor()) {
                    	//通过TestFpsActivity传入的Executor，将回调放到异步
                        listener.getExecutor().execute(new Runnable() {
                            @Override
                            public void run() {
                            	// 回调给TestFpsActivity
                                listener.doFrameAsync(visibleScene, taskCostMs, frameCostMs, dropFrame, isContainsFrame);
                            }
                        });
                    }
                }
            }
        } finally {
            long cost = System.currentTimeMillis() - start;
            // debug模式下，回调doFrameAsync中执行超过17ms，log警告
            if (config.isDebug() && cost > frameIntervalMs) {
                MatrixLog.w(TAG, "[notifyListener] warm! maybe do heavy work in doFrameSync! size:%s cost:%sms", listeners.size(), cost);
            }
        }
    }

从上面代码可以看出掉帧数dropFrame就是taskCostMs/frameIntervalMs。

  • taskCostMs：一帧的执行耗时
  • frameIntervalMs：默认是17ms，计算逻辑是Choreographer.mFrameIntervalNanos+1。

其中，Choreographer.mFrameIntervalNanos是屏幕刷新时间间隔，默认16ms。计算代码如下：

1
2
3
com.tencent.matrix.trace.tracer.FrameTracer

this.frameIntervalMs = TimeUnit.MILLISECONDS.convert(UIThreadMonitor.getMonitor().getFrameIntervalNanos(), TimeUnit.NANOSECONDS) + 1;
1
2
3
4
5
6
com.tencent.matrix.trace.core.UIThreadMonitor

choreographer = Choreographer.getInstance();

// 通过反射获取Choreographer的mFrameIntervalNanos字段，默认是16ms
frameIntervalNanos = reflectObject(choreographer, "mFrameIntervalNanos");

上面计算掉帧的方式：taskCostMs/17，其实并不是非常严谨，比如taskCostMs=33时，应该丢了两帧，但是计算结果是1。

上面提到的FrameTracer.notifyListener()由FrameTracer.doFrame()触发，看下FrameTracer.doFrame()：

FrameTracer.doFrame():
1
2
3
4
5
6
7
8
9
com.tencent.matrix.trace.tracer.FrameTracer

@Override
    public void doFrame(String focusedActivityName, long start, long end, long frameCostMs, long inputCostNs, long animationCostNs, long traversalCostNs) {
        if (isForeground()) {
            // IDoFrameListener.doFrameAsync()中的参数taskCostMs即为end - start。
            notifyListener(focusedActivityName, end - start, frameCostMs, frameCostMs >= 0);
        }
    }

这个方法没有做太多事情，主要是计算掉帧数用的taskCostMs是end - start的结果。

FrameTracer.doFrame()由UIThreadMonitor.dispatchEnd()触发，看下后者的实现。

UIThreadMonitor.dispatchEnd()
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
com.tencent.matrix.trace.core.UIThreadMonitor

    private void dispatchEnd() {
        if (isBelongFrame) {
            doFrameEnd(token);
        }

        // 对应每一帧的开始时间，在dispatchBegin()中赋值
        long start = token;
        // 对应每一帧的结束时间
        long end = SystemClock.uptimeMillis();

        synchronized (observers) {
            for (LooperObserver observer : observers) {
                if (observer.isDispatchBegin()) {
                	// isBelongFrame ? end - start : 0 - frameCost, 如果是帧耗时计算，则frameCost为0，否则和taskCost一样
                	// queueCost数组，存储对应Choreographer中三类task(input/animation/traversal)的耗时
                    observer.doFrame(AppMethodBeat.getVisibleScene(), token, SystemClock.uptimeMillis(), isBelongFrame ? end - start : 0, queueCost[CALLBACK_INPUT], queueCost[CALLBACK_ANIMATION], queueCost[CALLBACK_TRAVERSAL]);
                }
            }
        }

        // 计算结束时间
        dispatchTimeMs[3] = SystemClock.currentThreadTimeMillis();
        dispatchTimeMs[1] = SystemClock.uptimeMillis();

        AppMethodBeat.o(AppMethodBeat.METHOD_ID_DISPATCH);

        synchronized (observers) {
            for (LooperObserver observer : observers) {
                if (observer.isDispatchBegin()) {
                    observer.dispatchEnd(dispatchTimeMs[0], dispatchTimeMs[2], dispatchTimeMs[1], dispatchTimeMs[3], token, isBelongFrame);
                }
            }
        }

    }

这部分内容主要做了这几件事情：

  • 获取每一帧耗时的开始、结束时间戳，即start、end，将差值通过observer.doFrame()传给消费方
  • 执行observer.doFrame()，该方法主要消费方是AnrTracer、EvilMethodTracer、FrameTracer
  • 赋值dispatchTimeMs[1]，dispatchTimeMs[3]，其中dispatchTimeMs数组含义后面会提到
  • 执行observer.dispatchEnd()，该方法主要消费方是AnrTracer、EvilMethodTracer

看完了UIThreadMonitor.dispatchEnd()，再看下UIThreadMonitor.dispatchBegin()：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
com.tencent.matrix.trace.core.UIThreadMonitor

private void dispatchBegin() {
        // 对dispatchTimeMs[0]、dispatchTimeMs[2]赋值
        token = dispatchTimeMs[0] = SystemClock.uptimeMillis();
        dispatchTimeMs[2] = SystemClock.currentThreadTimeMillis();
        AppMethodBeat.i(AppMethodBeat.METHOD_ID_DISPATCH);

        //每一帧开始执行时的回调
        synchronized (observers) {
            for (LooperObserver observer : observers) {
                if (!observer.isDispatchBegin()) {
                    observer.dispatchBegin(dispatchTimeMs[0], dispatchTimeMs[2], token);
                }
            }
        }
    }

这里简单说下SystemClock.uptimeMillis()和SystemClock.currentThreadTimeMillis()的区别，详细内容可以看官方文档：

  • SystemClock.uptimeMillis()：记录从开机到现在的时长，系统深睡眠（CPU睡眠、黑屏、系统等待外部输入对其唤醒）的时间不算在内，且不受系统设置时间调整的影响。是大多数时间间隔计算方法的基础，比如Thread.sleep(long)、Object.wait(long)、System.nanoTime()
  • SystemClock.currentThreadTimeMillis()：这个比较容易理解，当前线程的活动时长（线程处于running状态）
LooperObserver.dispatchEnd()

解释下LooperObserver.dispatchEnd()的参数含义，后续对理解AnrTracer、EvilMethodTracer的实现有帮助：

1
2
3
com.tencent.matrix.trace.listeners.LooperObserver

public void dispatchEnd(long beginMs, long cpuBeginMs, long endMs, long cpuEndMs, long token, boolean isBelongFrame)
  • beginMs：主线程一帧任务的开始时间点，对应dispatchTimeMs[0]，在UIThreadMonitor.dispatchBegin()中赋值
  • cpuBeginMs：当前线程活动期间，方法开始执行时间点，对应dispatchTimeMs[2]
  • endMs：主线程一帧方法结束执行时间点，对应dispatchTimeMs[1]，在UIThreadMonitor.dispatchEnd()中赋值。所以，一帧耗时就是endMs-beginMs。
  • cpuEndMs：当前线程活动期间，方法解释执行时间点，对应dispatchTimeMs[3]
  • token：等同于beginMs
  • isBelongFrame：可简单理解为是否属于主线程任务。在Choreographer处理input任务时执行UIThreadMonitor.run()，内部将isBelongFrame置为true，这块逻辑可以看下UIThreadMonitor.onStart()

上面提到，一帧任务执行结束时会执行UIThreadMonitor.dispatchEnd()，该方法在LooperMonitor注册的监听器中执行的。看下这块逻辑：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
com.tencent.matrix.trace.core.UIThreadMonitor

LooperMonitor.register(new LooperMonitor.LooperDispatchListener() {
            @Override
            public boolean isValid() {
                return isAlive;
            }

            @Override
            public void dispatchStart() {
                super.dispatchStart();
                UIThreadMonitor.this.dispatchBegin();
            }

            @Override
            public void dispatchEnd() {
                super.dispatchEnd();
                UIThreadMonitor.this.dispatchEnd();
            }

        });

UIThreadMonitor向LooperMonitor注册了监听器，用于监听每一帧的开始和结束。

其中，LooperDispatchListener的dispatchStart()和dispatchEnd()都是LooperMonitor.dispatch()执行的。由isBegin决定执行dispatchStart()还是dispatchEnd()。看下LooperMonitor.dispatch()：

LooperMonitor.dispatch():
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
com.tencent.matrix.trace.core.LooperMonitor

private void dispatch(boolean isBegin, String log) {
        for (LooperDispatchListener listener : listeners) {
            if (listener.isValid()) {
                if (isBegin) {
                    if (!listener.isHasDispatchStart) {
                        // 内部回调dispatchStart()
                        listener.onDispatchStart(log);
                    }
                } else {
                    if (listener.isHasDispatchStart) {
                        // 内部回调dispatchEnd()
                        listener.onDispatchEnd(log);
                    }
                }
            } else if (!isBegin && listener.isHasDispatchStart) {
                listener.dispatchEnd();
            }
        }

    }

isBegin的逻辑看下面代码：

LooperMonitor.LooperPrinter:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
com.tencent.matrix.trace.core.LooperMonitor

class LooperPrinter implements Printer {
       
        @Override
        public void println(String x) {
            ...

            if (!isHasChecked) {
            	// 根据参数x内容，判断是开始还是结束，即isBegin
                isValid = x.charAt(0) == '>' || x.charAt(0) == '<';
                isHasChecked = true;
                if (!isValid) {
                    MatrixLog.e(TAG, "[println] Printer is inValid! x:%s", x);
                }
            }

            if (isValid) {
                // x.charAt(0) == '>'时，isBegin为true
                dispatch(x.charAt(0) == '>', x);
            }

        }
    }

即，入参字符串x以>开头时，isBegin为true。

上面逻辑是自定义LooperPrinter的实现方法。在LooperMonitor初始化时，会向main looper注册一个LooperPrinter：

1
2
3
4
5
6
7
8
9
10
com.tencent.matrix.trace.core.LooperMonitor

public class LooperMonitor {
	private LooperPrinter printer;
	//主线程looper
	looper = Looper.getMainLooper()

	// 将前面提到的自定义LooperPrinter塞给主线程looper
	looper.setMessageLogging(printer = new LooperPrinter(originPrinter));
}

上面代码主要是把自定义LooperPrinter塞给主线程looper。对Looper比较熟悉的同学其实已经有眉目了，我们回顾下looper的逻辑：

Looper.loop()
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
android.os.Looper.java

public static void loop() {
        final Looper me = myLooper();
        if (me == null) {
            throw new RuntimeException("No Looper; Looper.prepare() wasn't called on this thread.");
        }
        final MessageQueue queue = me.mQueue;

        ...

        for (;;) {
            Message msg = queue.next(); // might block
            if (msg == null) {
                // No message indicates that the message queue is quitting.
                return;
            }

            // This must be in a local variable, in case a UI event sets the logger
            // logging对象外部自定义，传入一个自定义Printer实现每一帧的监听计算
            final Printer logging = me.mLogging;
            if (logging != null) {
                // 每一帧开始时打印的log
                logging.println(">>>>> Dispatching to " + msg.target + " " +
                        msg.callback + ": " + msg.what);
            }
            ...
            try {
            		// 消息执行
            		msg.target.dispatchMessage(msg);
                dispatchEnd = needEndTime ? SystemClock.uptimeMillis() : 0;
            } finally {
                if (traceTag != 0) {
                    Trace.traceEnd(traceTag);
                }
            }
            ...
            if (logging != null) {
            		// 每一帧结束时打印的log
            		logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
            }
            ...
        }
    }

很多APM计算帧率都采用了这个逻辑，我在Android图形渲染之Choreographer原理 最后也提到使用“Looper & Printer”计算帧率。

Looper在每个消息消费前后msg.target.dispatchMessage(msg)，会通过一个Printer对象分别打印>>>>> Dispatching to…和<<<<< Finished to两个日志。通过Looper.setMessageLogging()可以设置我们自定义的Printer，通过监听主线程方法执行前后的两个日志字符串，就可以计算一帧的耗时。

前面LooperMonitor中就通过Looper.setMessageLogging()将自定义的Printer传给了Looper，所以可以拦截每个消息执行前后的日志。

到这里，每一帧的监听、掉帧逻辑及帧率计算方式就讲完了。

总结：

回顾下整体代码的执行过程：

1
2
3
4
5
6
7
- Looper.loop()		//主线程消息执行也是looper机制
- LooperMonitor.LooperPrinter.println()		//消息执行前后会打印两个日志
- LooperMonitor.dispatch()	//拦截到两个日志后进行分发
- UIThreadMonitor.dispatchBegin()/dispatchEnd()	//记录相关时间节点，分发每一帧执行前后的回调方法
- FrameTracer.doFrame()
- FrameTracer.notifyListener()
- TestFpsActivity.IDoFrameListener.doFrameSync()/doFrameAsync()	//业务侧获取帧率回调

总体来说，帧率检测使用了“Looper & Printer”方式。Printer的日志字符串对应主线程每一帧方法执行的开始和结束，通过给主线程Looper设置自定义Printer，即可拦截日志。根据日志内容即可得知每一帧执行的前后节点，进而记录每一帧的开始、结束时间戳，从而可以计算每一帧的耗时、帧率、掉帧等核心指标。

ANR检测

ANR检测的主要实现在AnrTracer。

demo中，将TestTraceMainActivity.testANR()内部执行耗时改大一点（大于5000ms），比如改到7800，就能看到AS中输出如下ANR警告log：

看下AnrTracer如何统计ANR，收集上述log信息：

AnrTracer：
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
com.tencent.matrix.trace.tracer.AnrTracer

@Override
    public void dispatchBegin(long beginMs, long cpuBeginMs, long token) {
        super.dispatchBegin(beginMs, cpuBeginMs, token);
        // 构造AnrTask
        anrTask = new AnrHandleTask(AppMethodBeat.getInstance().maskIndex("AnrTracer#dispatchBegin"), token);
        
        // 延迟5s发消息，Constants.DEFAULT_ANR = 5 * 1000
        // token是方法开始执行的时间
        // (SystemClock.uptimeMillis() - token)：校正方法的开始时间
        anrHandler.postDelayed(anrTask, Constants.DEFAULT_ANR - (SystemClock.uptimeMillis() - token));
    }

    @Override
    public void dispatchEnd(long beginMs, long cpuBeginMs, long endMs, long cpuEndMs, long token, boolean isBelongFrame) {
        super.dispatchEnd(beginMs, cpuBeginMs, endMs, cpuEndMs, token, isBelongFrame);
        // 移除anrTask
        if (null != anrTask) {
            anrTask.getBeginRecord().release();
            anrHandler.removeCallbacks(anrTask);
        }
    }

前面讲FrameTracer时提到过，每一帧执行前后分别回调Tracer.dispatchBegin()和Tracer.dispatchEnd()。

上面代码在dispatchBegin()内部发送了一个延迟消息执行AnrTask，延迟时间约为5s（Constants.DEFAULT_ANR = 5 * 1000），在dispatchEnd()移除对应的任务。所以，如果主线程一帧执行任务超过5s，AnrTask就会执行。

要注意的一点是，ANR log中，may be happen ANR(5007ms)!，这里的5007ms时间并不是一帧任务的耗时（因为我们把测试方法耗时改成了7800ms），而是AnrTracer中AnrTask的消息延迟时间。

AnrTask：

看下AnrTask的逻辑：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
com.tencent.matrix.trace.tracer.AnrTracer.AnrHandleTask

@Override
public void run() {
    long curTime = SystemClock.uptimeMillis();
    boolean isForeground = isForeground();
    
    // process 进程信息
    int[] processStat = Utils.getProcessPriority(Process.myPid());
    long[] data = AppMethodBeat.getInstance().copyData(beginRecord);
    beginRecord.release();
    // 业务场景，FrameTracer中提到过
    String scene = AppMethodBeat.getVisibleScene();

    // memory 内存信息，其中VmSize从“/proc/{PID}/status”文件中获取
    long[] memoryInfo = dumpMemory();

    // Thread state
    Thread.State status = Looper.getMainLooper().getThread().getState();
    
    // 线程调用堆栈
    StackTraceElement[] stackTrace = Looper.getMainLooper().getThread().getStackTrace();
    // 堆栈裁剪
    String dumpStack = Utils.getStack(stackTrace, "|*\t\t", 12);

    // frame
    UIThreadMonitor monitor = UIThreadMonitor.getMonitor();
    // 获取input/animation/traversal三类任务耗时
    long inputCost = monitor.getQueueCost(UIThreadMonitor.CALLBACK_INPUT, token);
    long animationCost = monitor.getQueueCost(UIThreadMonitor.CALLBACK_ANIMATION, token);
    long traversalCost = monitor.getQueueCost(UIThreadMonitor.CALLBACK_TRAVERSAL, token);

    // trace
    ...

    StringBuilder reportBuilder = new StringBuilder();
    StringBuilder logcatBuilder = new StringBuilder();
    
    // 获取ANR时长
    long stackCost = Math.max(Constants.DEFAULT_ANR, TraceDataUtils.stackToString(stack, reportBuilder, logcatBuilder));

    // stackKey
    String stackKey = TraceDataUtils.getTreeKey(stack, stackCost);
    
    // 打印ANR日志
    MatrixLog.w(TAG, "%s \npostTime:%s curTime:%s",
            printAnr(scene, processStat, memoryInfo, status, logcatBuilder, isForeground, stack.size(), stackKey, dumpStack, inputCost, animationCost, traversalCost, stackCost), token, curTime); // for logcat

    if (stackCost >= Constants.DEFAULT_ANR_INVALID) {
        MatrixLog.w(TAG, "The checked anr task was not executed on time. "
                + "The possible reason is that the current process has a low priority. just pass this report");
        return;
    }
    
    // report 启动IssuesListActivity页面，展示ANR信息
    ...

}

主要内容都加了注释，可以参考下。

总结：

  • ANR的检测逻辑：在主线程一帧任务开始前发送（5s）的延迟消息，任务结束时移除该消息。如果主线程一帧任务执行时间超过了消息的延迟时间（认为这一帧导致了ANR），延迟消息将会执行，触发ANR信息收集任务

  • 延迟消息（AnrTask）在异步线程执行，收集进程、调用堆栈、内存使用、trace信息，后续将信息log出来，并启动IssuesListActivity展示ANR结果。

慢函数检测

将TestTraceMainActivity.testANR()实现耗时改成7800ms，AS会输出如下慢函数log。从log中可以看出发生了Jankiness，方法耗时7804ms，和我们的修改基本吻合。

下面看下慢函数的实现逻辑，主要代码在EvilMethodTracer。

EvilMethodTracer：
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
com.tencent.matrix.trace.tracer.EvilMethodTracer

@Override
    public void dispatchEnd(long beginMs, long cpuBeginMs, long endMs, long cpuEndMs, long token, boolean isBelongFrame) {
        super.dispatchEnd(beginMs, cpuBeginMs, endMs, cpuEndMs, token, isBelongFrame);
        long start = config.isDevEnv() ? System.currentTimeMillis() : 0;
        try {
            long dispatchCost = endMs - beginMs;
            // 一帧耗时超过evilThresholdMs（默认700ms），执行慢函数计算逻辑
            if (dispatchCost >= evilThresholdMs) {
                long[] data = AppMethodBeat.getInstance().copyData(indexRecord);
                long[] queueCosts = new long[3];
                System.arraycopy(queueTypeCosts, 0, queueCosts, 0, 3);
                String scene = AppMethodBeat.getVisibleScene();
                // 异步线程执行AnalyseTask
                MatrixHandlerThread.getDefaultHandler().post(new AnalyseTask(isForeground(), scene, data, queueCosts, cpuEndMs - cpuBeginMs, endMs - beginMs, endMs));
            }
        } finally {
            ...
        }
    }

主要逻辑在dispatchEnd()里面。从上面代码可以看出，当主线程一帧内耗时超过evilThresholdMs（默认700ms，可以通过TraceConfig配置），执行慢函数的警告，打印上面提到的log。

其中，慢函数的耗时，就是上面代码中的endMs - beginMs，这个逻辑在“帧率检测 - UIThreadMonitor.dispatchEnd()”中有具体讲到。

具体慢函数打印的log逻辑如下：

AnalyseTask:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
com.tencent.matrix.trace.tracer.EvilMethodTracer.AnalyseTask

private class AnalyseTask implements Runnable {
        ...

        void analyse() {

            // process 进程信息
            int[] processStat = Utils.getProcessPriority(Process.myPid());
            String usage = Utils.calculateCpuUsage(cpuCost, cost);
            LinkedList<MethodItem> stack = new LinkedList();
            ...

            StringBuilder reportBuilder = new StringBuilder();
            StringBuilder logcatBuilder = new StringBuilder();
            long stackCost = Math.max(cost, TraceDataUtils.stackToString(stack, reportBuilder, logcatBuilder));
            String stackKey = TraceDataUtils.getTreeKey(stack, stackCost);

					// 和AnrTracer一样，打印log，启动IssuesListActivity页面，展示EvilMethod信息
            MatrixLog.w(TAG, "%s", printEvil(scene, processStat, isForeground, logcatBuilder, stack.size(), stackKey, usage, queueCost[0], queueCost[1], queueCost[2], cost)); // for logcat

            ...
        }
    }

其中，AnalyseTask的逻辑和AnrTask类似，只是log中的部分内容不一样，就不具体展开了。

总结：

慢函数的检测逻辑比较简单，在主线程一帧执行结束时，判断帧耗时是否大于预先设置的慢函数阈值，超过该阈值，即认为慢函数发生。

启动耗时检测

App三种启动方式：

官方定义了三种启动方式：

  • 冷启动：彻底杀死应用进程后启动APP的方式。系统会为应用创建进程、主线程，执行Application、launch Activity的初始化方法。
  • 热启动：没有杀死应用进程情况下启动APP的方式，比如应用切到后台。热启动中，系统的所有工作就是将您的 Activity 带到前台。这种情况不会执行Application的初始化方法，如果应用的所有 Activity 都还驻留在内存中，则应用可以无须重复对象初始化、布局inflate和呈现。
  • 温启动：
    • 有两种常见场景：
      • 点击回退键方式退出应用
      • 应用在后台被系统回收
    • 启动逻辑介于冷启动和热启动之间。如果是回退键方式退出应用再重启，不会执行Application初始化，但是需要初始化Activity。如果是系统回收后的重启，Application和Activity都会初始化，但是可以通过savedInstanceState拿到退出前Activity的状态。
冷启动关键节点：

三种启动方式中，我们这里只对冷启动做分析。启动Demo后，可以看到如下log：

1
Matrix.StartupTracer: [report] applicationCost:42 firstScreenCost:244 allCost:2306 isWarmStartUp:false

log显示是冷启动(isWarmStartUp:false)方式，Application初始化耗时(applicationCost) 42ms，首屏耗时(firstScreenCost) 244ms，总耗时(allCost) 2306ms。通过log可以知道是StartupTracer做的上报。

StartupTracer给各个耗时统计点提供了注释：

简单解释下上图中几个关键统计点：

  • Application初始化耗时(applicationCost)：
    • 起始点对应Application.onCreate()，由ActivityThreadHacker.sApplicationCreateBeginTime字段记录起始点时间戳，该字段在ActivityThreadHacker.hackSysHandlerCallback()赋值。
    • 结束点比较有意思，matrix是通过hook ActivityThread的mH.mCallback实现拦截主线程message，Application和Activity的初始化任务都是通过主线程Handler机制调度的。当接收到launch activity调度message时认为Application初始化完成，以此作为结束点。结束点由ActivityThreadHacker.sApplicationCreateEndTime字段记录其时间戳，该字段在ActivityThreadHacker.HackCallback.handleMessage()中赋值。
  • 首屏耗时(firstScreenCost)：
    • 指app启动到第一个Activity(launch activity)初始化完成的耗时，可以认为包含了applicationCost + launch activity的初始化耗时。
    • 起始点和applicationCost的起始点一样，由ActivityThreadHacker.sApplicationCreateBeginTime字段记录时间戳。
    • 结束点对应launch activity的onWindowFocusChange()，在StartupTracer.onActivityFocused()中标记。Activity.onWindowFocusChange()执行时，认为Activity对用户可见。
  • 冷启动耗时(coldCost)
    • app启动到第一个对用户有意义的Activity（对应图中的careActivity）初始化完成耗时。
    • 应用一般仅在闪屏页即launch activity做logo展示、应用初始化的工作，其后的第一个Activity做为主页Activity，这个Activity就是careActivity。所以把careActivity的初始化完成做为coldCost的结束点。
  • 温启动耗时(warmCost)
    • 因为Application不会重新初始化，所以只统计Activity的初始化耗时，和firstActivity含义一致。
    • 起始点是launchActivity初始化的开始点。
    • 结束点是launchActivity onWindfocusChanged()执行点。

上面解释了几个耗时节点的概念，接下来分别看看具体的实现逻辑。

Application初始化耗时：

前面讲到，Application初始化耗时的获取方式是ActivityThreadHacker.getApplicationCost()：

1
2
3
4
5
com.tencent.matrix.trace.hacker.ActivityThreadHacker

public static long getApplicationCost() {
        return ActivityThreadHacker.sApplicationCreateEndTime - ActivityThreadHacker.sApplicationCreateBeginTime;
    }

其实就是sApplicationCreateEndTime和sApplicationCreateBeginTime的差值。

其中，sApplicationCreateBeginTime在ActivityThreadHacker.hackSysHandlerCallback()中赋值：

1
2
3
4
5
6
7
com.tencent.matrix.trace.hacker.ActivityThreadHacker

public static void hackSysHandlerCallback() {
        ...
        sApplicationCreateBeginTime = SystemClock.uptimeMillis();
        ...
}

那么，ActivityThreadHacker.hackSysHandlerCallback()什么时机执行呢？

在方法内部打个断点，冷启动APP后，可看到方法调用栈如下图：

matrix_ActivityThreadHacker_method_trace

从上图方法调用栈可以看到，MatrixApplication.onCreate()调用AppMethodBeat.i()（插桩实现），后续执行ActivityThreadHacker.hackSysHandlerCallback()，所以sApplicationCreateBeginTime在Application.onCreate()执行后被赋值。符合前面解释applicationCost概念时提到的起始点对应Application.onCreate()。

sApplicationCreateEndTime在ActivityThreadHacker.HackCallback.handleMessage()中赋值。

下面看下ActivityThreadHacker相关逻辑。

在讲ActivityThreadHacker.HackCallback.handleMessage()前先了解下ActivityThreadHacker这个类。先看下ActivityThreadHacker.hackSysHandlerCallback()：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
com.tencent.matrix.trace.hacker.ActivityThreadHacker

public static void hackSysHandlerCallback() {
        try {
            // application初始化耗时过程起始点
            sApplicationCreateBeginTime = SystemClock.uptimeMillis();
            sApplicationCreateBeginMethodIndex = AppMethodBeat.getInstance().maskIndex("ApplicationCreateBeginMethodIndex");
            
            // step1. 通过反射获取ActivityThread.sCurrentActivityThread对象
            Class<?> forName = Class.forName("android.app.ActivityThread");
            Field field = forName.getDeclaredField("sCurrentActivityThread");
            field.setAccessible(true);
            Object activityThreadValue = field.get(forName);
            
            // step2. 通过反射获取sCurrentActivityThread的mH对象
            Field mH = forName.getDeclaredField("mH");
            mH.setAccessible(true);
            Object handler = mH.get(activityThreadValue);
            
            // step3. 将mH中的mCallback设置成HackCallback，拦截主线程消息
            Class<?> handlerClass = handler.getClass().getSuperclass();
            Field callbackField = handlerClass.getDeclaredField("mCallback");
            callbackField.setAccessible(true);
            Handler.Callback originalCallback = (Handler.Callback) callbackField.get(handler);
            HackCallback callback = new HackCallback(originalCallback);
            callbackField.set(handler, callback);
        } catch (Exception e) {
            MatrixLog.e(TAG, "hook system handler err! %s", e.getCause().toString());
        }
    }

上面这部分代码，除了记录Application的初始化开始节点sApplicationCreateBeginTime，还通过反射，将ActivityThreadHacker.HackCallback实例设置成主线程Handler的mCallback。这样，就可以拦截主线程消息做一些工作。

对ActivityThread、应用启动流程不熟悉的同学可以看看这篇文章：Android应用启动流程分析。

看下ActivityThreadHacker.HackCallback拦截主线程消息做了哪些工作：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
com.tencent.matrix.trace.hacker.ActivityThreadHacker

private final static class HackCallback implements Handler.Callback {
        private static final int LAUNCH_ACTIVITY = 100;
        private static final int CREATE_SERVICE = 114;
        private static final int RECEIVER = 113;
        public static final int EXECUTE_TRANSACTION = 159; // for Android 9.0
        private static boolean isCreated = false;
        private static int hasPrint = 10;

        ...

        @Override
        public boolean handleMessage(Message msg) {
            ...
            // 是否启动页Activity，实现逻辑后面会讲到
            boolean isLaunchActivity = isLaunchActivity(msg);
            // 记录启动页Activity结束时间点
            if (isLaunchActivity) {
                ActivityThreadHacker.sLastLaunchActivityTime = SystemClock.uptimeMillis();
                ActivityThreadHacker.sLastLaunchActivityMethodIndex = AppMethodBeat.getInstance().maskIndex("LastLaunchActivityMethodIndex");
            }

            if (!isCreated) {
                // 当前message是启动页Activity时，认为Application初始化完成
                if (isLaunchActivity || msg.what == CREATE_SERVICE || msg.what == RECEIVER) {
                    ActivityThreadHacker.sApplicationCreateEndTime = SystemClock.uptimeMillis();
                    ActivityThreadHacker.sApplicationCreateScene = msg.what;
                    isCreated = true;
                }
            }

            return null != mOriginalCallback && mOriginalCallback.handleMessage(msg);
        }
}

上面代码主要意思是，当ActivityThread.HackCallback收到launch activity的初始化message时，记录Application的初始化结束点时间戳。

总结：

  • Application初始化过程的起始点对应Application.onCreate()
  • 结束点是接收到launch activity初始化消息的时刻
Launch Activity初始化耗时：

接下来看下launch activity即闪屏页的初始化耗时计算逻辑。

ActivityThreadHacker中有个方法是获取launch activity的启动时间点：

1
2
3
public static long getLastLaunchActivityTime() {
        return ActivityThreadHacker.sLastLaunchActivityTime;
    }

从上面《Application初始化耗时》部分，ActivityThreadHacker.HackCallback.handleMessage()中可以看到，接收到launch activity的消息时，对ActivityThreadHacker.sLastLaunchActivityTime赋值。

那怎么判断一个消息是launch activity的消息呢？看下面代码：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
com.tencent.matrix.trace.hacker.ActivityThreadHacker

private boolean isLaunchActivity(Message msg) {
    // 区分版本，9.0及以上检测ClientTransaction
    if (Build.VERSION.SDK_INT > Build.VERSION_CODES.O_MR1) {
        if (msg.what == EXECUTE_TRANSACTION && msg.obj != null) {
            try {
                if (null == method) {
                    Class clazz = Class.forName("android.app.servertransaction.ClientTransaction");
                    method = clazz.getDeclaredMethod("getCallbacks");
                    method.setAccessible(true);
                }
                List list = (List) method.invoke(msg.obj);
                if (!list.isEmpty()) {
                    return list.get(0).getClass().getName().endsWith(".LaunchActivityItem");
                }
            } catch (Exception e) {
                MatrixLog.e(TAG, "[isLaunchActivity] %s", e);
            }
        }
        return msg.what == LAUNCH_ACTIVITY;
    } else {
        // 9.0以下版本
        return msg.what == LAUNCH_ACTIVITY;
    }
}

在Android应用启动流程分析这篇文章中我们提到过，Android9.0引入了ClientTransaction辅助管理应用和页面的生命周期。Application初始化时，AMS通过ActivityThread.ApplicationThread向ActivityThread.mH发送一个what为EXECUTE_TRANSACTION，obj为ClientTransaction的消息，且该消息中的ClientTransaction带有一个LaunchActivityItem的Callback。

所以上面isLaunchActivity()就是通过这个思路检测launch activity的，发现符合条件的主线程消息，且消息的第一个callback类名以LaunchActivityItem为结尾，即认为发起launch activity初始化流程。

StartupTracer：

上面分别讲了应用冷启动各个阶段的耗时统计逻辑，在文章开头处我们提到StartupTracer负责应用启动耗时检测，接下来看看StartupTracer主要做了哪些事情。

看下StartupTracer的主要方法onActivityFocused()，该方法在Activity.onWindfocusChanged()中被调用。这个调用是通过插桩实现的，关于Matrix的插桩内容也比较有意思，后面单独文章来介绍。

Activity.onWindfocusChanged()被执行，就认为页面已经展现在用户面前，通常做为页面初始化过程的结束点。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
com.tencent.matrix.trace.tracer.StartupTracer

    @Override
    public void onActivityFocused(String activity) {
    	// coldCost == 0时认为是冷启动状态
        if (isColdStartup()) {
            if (firstScreenCost == 0) {
            	// 第一个Activity的onWindowFocusChanged()执行时统计首屏耗时
                this.firstScreenCost = uptimeMillis() - ActivityThreadHacker.getEggBrokenTime();
            }
            
            //闪屏页已经初始化，其之后的第一个Activity.onWindowFocusChanged()执行时，开始统计冷启动耗时
            if (hasShowSplashActivity) {
                coldCost = uptimeMillis() - ActivityThreadHacker.getEggBrokenTime();
            } else {
            	// 判断闪屏页是否启动，splashActivities在MatrixApplication.onCraete是配置的
                if (splashActivities.contains(activity)) {
                    hasShowSplashActivity = true;
                } else if (splashActivities.isEmpty()) {
                    coldCost = firstScreenCost;
                } else {
                    ...
                }
            }
            
            // 冷启动后，执行AnalyseTask
            if (coldCost > 0) {
                analyse(ActivityThreadHacker.getApplicationCost(), firstScreenCost, coldCost, false);
            }

        } else if (isWarmStartUp()) {
            // 温启动和冷启动逻辑类似，记录的开始、结束点前面概念部分已经讲到
        }

    }

再解释下上面部分代码：

  • isColdStartup()：coldCost为0时即为冷启动。
  • firstScreenCost：应用启动到闪屏页Activity.onWindfocusChanged()执行的时长
  • coldCost：闪屏页初始化后，其之后的第一个Activity(careActivity).onWindfocusChanged()执行时，计算冷启动耗时。本质上用户看到了第二个Activity，比firstScreenCost多了闪屏页展现时间+careActivity的初始化耗时。
  • applicationCost：Application初始化耗时
  • ActivityThreadHacker.getEggBrokenTime()：应用冷启动开始节点
  • splashActivities：保存闪屏页列表，在TraceConfig中初始化。demo中是在MatrixApplication.onCraete()手动配置splash Activity。

有了上面这些耗时统计，AnalyseTask利用这些数据，进行堆栈优化、数据整理，打印出前面的启动耗时log。

总结：
  • Application初始化耗时(applicationCost)：
    • 统计Application.onCreate()到ActivityThread.mH接收LaunchActivityItem消息这段过程的时间
  • 首屏耗时(firstScreenCost)：
    • 指app启动到闪屏页Activity(launch activity)初始化完成的耗时，可以认为包含了applicationCost + launch activity页面的初始化耗时
  • 冷启动耗时(coldCost)
    • app启动(Application.onCreate())到第一个对用户有意义的Activity（careActivity）初始化完成(Activity.onWindowFocusChanged())的耗时

参考

Matrix